Exit a language server if it sends a message with invalid json #9332

bendennis · 2024-01-13T15:43:14Z

I've been struggling to get c# + omnisharp working reliably with helix. Omnisharp occasionally sends messages with malformed json, which causes the helix LSP event listener thread to die. After this happens, the LSP functionality within helix no longer works, even though omnisharp is still up and running. If I try to close helix at this point, it hangs for a bit and writes an lsp shutdown timeout log. If I run :lsp-restart, a second instance of omnisharp is started, leaving the first one running in the background.

This PR updates the recv function in helix-lsp::transport to request that an LSP is exited after it sends a message that cannot be parsed. This causes the Language server exited message to be displayed in the status bar within the editor. Surprisingly, the omnisharp process is still running at this point. Despite that, exiting helix is quick and running :lsp-restart restarts the process as expected.

Additionally, I updated some logging that caused confusion as I was troubleshooting.

…ed from the lsp server

pascalkuthe · 2024-01-13T16:37:00Z

This is definitely a bug in the language server it should never be sending invalid json. I think this could be an ok change to be a bit more robust but I would add somekind of counter to abort after a give counter of invalid messages received (without any valid messages) to avoid keeping an obviously crashing/crashed/missebhaving program alive forever. What do you think @the-mikedavis

the-mikedavis · 2024-01-14T14:23:45Z

I expected to see something in the JSONRPC spec about closing connections that send invalid JSON but it looks like we're only obligated to send an error response back when we receive a request with invalid JSON: https://www.jsonrpc.org/specification#error_object. (The message in the post is a notification though, so no response is necessary.) And the LSP spec doesn't say anything about invalid JSON. I think that closing the connection when we get non-JSON is reasonable though because JSONRPC says that we need to respond to all requests and if we can't parse a request enough to know that it's a request then we can't know that we have to respond to it.

Pragmatically I think it would be ok to make this change but it invites some extra complexity as @pascalkuthe says: we want servers that are obviously malfunctioning to exit rather than hang around forever. So I think this should really be fixed in omnisharp rather than any changes in Helix. I would prefer that we fail fast in Helix rather than trying to accomodate broken language servers.

bendennis · 2024-01-14T22:03:24Z

I agree that it would be ideal to fix the root cause in omnisharp. I actually created an issue over there initially. We'll see what comes of that. I might take a stab at debugging from that side if I have time.

There are some confusing aspects of the current helix behavior that made it harder to determine exactly what was going on. When the issue occurs, the LSP functionality just stops working from user's perspective. There's an error log for the json parse failure, but there are also a bunch of unrelated malformed notification from Language Server logs that don't seem to cause any issues. I thought it was confusing that some "malformed" messages cause issues while others don't. Maybe malformed should be changed to "undefined" or "unexpected" if those are actually valid messages that just don't follow the spec?

... a lot more malformed notification logs
2024-01-14T10:58:07.227 helix_term::application [ERROR] received malformed notification from Language Server: Unhandled
2024-01-14T10:58:07.929 helix_term::application [ERROR] received malformed notification from Language Server: Unhandled
2024-01-14T10:58:07.929 helix_term::application [ERROR] received malformed notification from Language Server: Unhandled
2024-01-14T10:58:08.702 helix_term::application [ERROR] received malformed notification from Language Server: Unhandled
2024-01-14T10:58:08.702 helix_term::application [ERROR] received malformed notification from Language Server: Unhandled
2024-01-14T10:58:08.976 helix_lsp::transport [ERROR] omnisharp err: <- Parse(Error("control character (\\u0000-\\u001F) found while parsing a string", line: 2, column: 0))

At this point, omnisharp is still running. If I try to close helix, it hangs for a bit and writes an lsp shutdown timeout log like the one below. If I run :lsp-restart, a second instance of omnisharp is started, leaving the first one running in the background.

2024-01-14T10:59:14.313 helix_term::application [ERROR] Timed out waiting for language servers to shutdown

If helix is going to bail on an lsp server that it thinks is unhealthy, I think it should do so completely and let the lsp server close before spinning up the new one. At that point, running :lsp-restart could be used to re-launch the lsp if desired. As long as the error logs make it clear what's going on, I think that'd be preferable to what happens today.

For now I think it probably makes sense to hold off on adding any additional complexity to account for straight up broken json coming from the lsp server.

If you think all that seems reasonable, I can take a swing at making the change to how the error is handled and logged.

the-mikedavis · 2024-01-15T18:59:21Z

Ah I see, in this case the client doesn't properly exit. Yeah let's properly shutdown the client in the Err case in recv doing all the cleanup we do for the StreamClosed error:

helix/helix-lsp/src/transport.rs

Lines 274 to 302 in eca3ccf

    
               // Close any outstanding requests. 
        
               for (id, tx) in transport.pending_requests.lock().await.drain() { 
        
                   match tx.send(Err(Error::StreamClosed)).await { 
        
                       Ok(_) => (), 
        
                       Err(_) => { 
        
                           error!("Could not close request on a closed channel (id={:?})", id) 
        
                       } 
        
                   } 
        
               } 
        
               // Hack: inject a terminated notification so we trigger code that needs to happen after exit 
        
               use lsp_types::notification::Notification as _; 
        
               let notification = 
        
                   ServerMessage::Call(jsonrpc::Call::Notification(jsonrpc::Notification { 
        
                       jsonrpc: None, 
        
                       method: lsp_types::notification::Exit::METHOD.to_string(), 
        
                       params: jsonrpc::Params::None, 
        
                   })); 
        
               match transport 
        
                   .process_server_message(&client_tx, notification, &transport.name) 
        
                   .await 
        
               { 
        
                   Ok(_) => {} 
        
                   Err(err) => { 
        
                       error!("err: <- {:?}", err); 
        
                   } 
        
               } 
        
               break; 
        
           }

Improving the logging sounds good too: we can probably log that line at info and have a more descriptive message so debugging wonky language servers is easier. The Unhandled error is benign - we just discard those messages - so there's no reason for it be logged at error level now.

…and close the language server

…what's done in send

helix-lsp/src/transport.rs

helix-term/src/application.rs

the-mikedavis

Thanks!

…-editor#9332) * Keep lsp event listener thread alive when malformed json is encountered from the lsp server * Update unexpected error flow in recv() to close outstanding requests and close the language server * Log malformed notifications as info instead of error * Make close_language_server a nested function inside recv, similar to what's done in send * Update malformed notification log text * Clean up new log text a bit * Initialize recv_buffer closer to where it's used * Use "exit" instead of "close" * Remove whitespace * Remove the need for a helper method to exit the language server * Match on Unhandled error explicitly and keep catch-all error case around

Keep lsp event listener thread alive when malformed json is encounter…

1ff12a7

…ed from the lsp server

pascalkuthe added A-language-server Area: Language server client S-waiting-on-review Status: Awaiting review from a maintainer. labels Jan 14, 2024

the-mikedavis added S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. and removed S-waiting-on-review Status: Awaiting review from a maintainer. labels Jan 15, 2024

bendennis added 8 commits January 15, 2024 20:37

Update unexpected error flow in recv() to close outstanding requests …

aafbd51

…and close the language server

Log malformed notifications as info instead of error

383fe43

Make close_language_server a nested function inside recv, similar to …

bef57cd

…what's done in send

Update malformed notification log text

e18329c

Clean up new log text a bit

1c14f21

Initialize recv_buffer closer to where it's used

efdd577

Use "exit" instead of "close"

68929b2

Remove whitespace

7366321

bendennis changed the title ~~Keep lsp event listener thread alive after malformed json is received from the server~~ Exit a language server if it sends a message with invalid json Jan 16, 2024

bendennis commented Jan 16, 2024

View reviewed changes

helix-lsp/src/transport.rs Outdated Show resolved Hide resolved

the-mikedavis reviewed Jan 16, 2024

View reviewed changes

helix-lsp/src/transport.rs Outdated Show resolved Hide resolved

helix-term/src/application.rs Show resolved Hide resolved

bendennis added 2 commits January 16, 2024 23:16

Remove the need for a helper method to exit the language server

00ed2e1

Match on Unhandled error explicitly and keep catch-all error case around

a008f0b

the-mikedavis approved these changes Jan 17, 2024

View reviewed changes

the-mikedavis added S-waiting-on-review Status: Awaiting review from a maintainer. and removed S-waiting-on-author Status: This is awaiting some action (such as code changes or more information) from the author. labels Jan 17, 2024

pascalkuthe approved these changes Jan 17, 2024

View reviewed changes

pascalkuthe merged commit dcdecaa into helix-editor:master Jan 17, 2024
6 checks passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Exit a language server if it sends a message with invalid json #9332

Exit a language server if it sends a message with invalid json #9332

bendennis commented Jan 13, 2024 •

edited

Loading

pascalkuthe commented Jan 13, 2024

the-mikedavis commented Jan 14, 2024

bendennis commented Jan 14, 2024

the-mikedavis commented Jan 15, 2024

the-mikedavis left a comment

Exit a language server if it sends a message with invalid json #9332

Exit a language server if it sends a message with invalid json #9332

Conversation

bendennis commented Jan 13, 2024 • edited Loading

pascalkuthe commented Jan 13, 2024

the-mikedavis commented Jan 14, 2024

bendennis commented Jan 14, 2024

the-mikedavis commented Jan 15, 2024

the-mikedavis left a comment

Choose a reason for hiding this comment

bendennis commented Jan 13, 2024 •

edited

Loading